Project

General

Profile

Actions

Bug #6284

closed

'\0' in log output

Added by neels 3 months ago. Updated 10 days ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
-
Target version:
-
Start date:
12/04/2023
Due date:
% Done:

80%

Spec Reference:

Description

I just ran manual osmo-cni tests, and to my surprise 'grep' and 'file' classify the resulting log files as binary.
Investigation shows that there are occasional zero octets at line starts in the files.
They reproducibly occur at the same places when re-starting, yet in seemingly non-deterministic places.

I see the zero octets both with 'log file foo.log' and 'log stderr' ( with 'osmo-msc >/tmp/x 2>&1 ),
but gsmtap_log shows no zero octets.

I see zero octets in all the logs except sipcon:

▶ file *.log
osmo-bsc-0.log:         data
osmo-hlr.log:           data
osmo-hnbgw.log:         data
osmo-mgw-for-bsc-0.log: data
osmo-mgw-for-hnbgw.log: data
osmo-mgw-for-msc.log:   data
osmo-msc.log:           data
osmo-sip-connector.log: ASCII text, with very long lines (314), with CRLF, LF line terminators, with escape sequences
osmo-stp-cn.log:        data

less:
(note the '^@')

20231204030908626 DMNCC NOTICE MNCC socket at /tmp/mncc_socket (mncc_sock.c:300)
^@20231204030908626 DLGLOBAL NOTICE Available via telnet 127.0.0.1 4254 (telnet_interface.c:88)
20231204030908626 DSMPP NOTICE SMPP at 127.0.0.1 2775 (smpp_smsc.c:989)
20231204030908626 DLCTRL NOTICE CTRL at 127.0.0.1 4255 (control_if.c:1014)
^@20231204030908626 DLGSUP NOTICE GSUP connecting to 127.0.0.5:4222 (gsup_client.c:74)
^@20231204030908626 DLGLOBAL DEBUG validating counter group 0x55bb61c9b660(sms_queue) with 5 counters (rate_ctr.c:86)
20231204030908627 DDB NOTICE Init database connection to 'sms.db' using SQLite3 lib version 3.40.1 (db.c:521)
20231204030908627 DDB DEBUG SQLite3 compiled with 'ATOMIC_INTRINSICS=1' (db.c:530)
20231204030908627 DDB DEBUG SQLite3 compiled with 'COMPILER=gcc-12.2.0' (db.c:530)

hexdump -C:
(marked zero octets with \*00\*)

00000000  1b 5b 31 3b 33 39 6d 32  30 32 33 31 32 30 34 30  |.[1;39m202312040|
00000010  33 30 39 30 38 36 32 36  20 1b 5b 31 3b 33 33 6d  |30908626 .[1;33m|
00000020  44 4d 4e 43 43 1b 5b 30  3b 6d 1b 5b 31 3b 33 39  |DMNCC.[0;m.[1;39|
00000030  6d 20 1b 5b 31 3b 33 33  6d 4e 4f 54 49 43 45 1b  |m .[1;33mNOTICE.|
00000040  5b 30 3b 6d 1b 5b 31 3b  33 39 6d 20 4d 4e 43 43  |[0;m.[1;39m MNCC|
00000050  20 73 6f 63 6b 65 74 20  61 74 20 2f 74 6d 70 2f  | socket at /tmp/|
00000060  6d 6e 63 63 5f 73 6f 63  6b 65 74 20 28 6d 6e 63  |mncc_socket (mnc|
00000070  63 5f 73 6f 63 6b 2e 63  3a 33 30 30 29 1b 5b 30  |c_sock.c:300).[0|
00000080  3b 6d 0a*00*32 30 32 33  31 32 30 34 30 33 30 39  |;m..202312040309|  <---
00000090  30 38 36 32 36 20 1b 5b  31 3b 33 33 6d 44 4c 47  |08626 .[1;33mDLG|
000000a0  4c 4f 42 41 4c 1b 5b 30  3b 6d 20 1b 5b 31 3b 33  |LOBAL.[0;m .[1;3|
000000b0  33 6d 4e 4f 54 49 43 45  1b 5b 30 3b 6d 20 41 76  |3mNOTICE.[0;m Av|
000000c0  61 69 6c 61 62 6c 65 20  76 69 61 20 74 65 6c 6e  |ailable via teln|
000000d0  65 74 20 31 32 37 2e 30  2e 30 2e 31 20 34 32 35  |et 127.0.0.1 425|
000000e0  34 20 28 74 65 6c 6e 65  74 5f 69 6e 74 65 72 66  |4 (telnet_interf|
000000f0  61 63 65 2e 63 3a 38 38  29 0a 32 30 32 33 31 32  |ace.c:88).202312|
00000100  30 34 30 33 30 39 30 38  36 32 36 20 1b 5b 31 3b  |04030908626 .[1;|
00000110  33 33 6d 44 53 4d 50 50  1b 5b 30 3b 6d 20 1b 5b  |33mDSMPP.[0;m .[|
00000120  31 3b 33 33 6d 4e 4f 54  49 43 45 1b 5b 30 3b 6d  |1;33mNOTICE.[0;m|
00000130  20 53 4d 50 50 20 61 74  20 31 32 37 2e 30 2e 30  | SMPP at 127.0.0|
00000140  2e 31 20 32 37 37 35 20  28 73 6d 70 70 5f 73 6d  |.1 2775 (smpp_sm|
00000150  73 63 2e 63 3a 39 38 39  29 0a 1b 5b 33 38 3b 35  |sc.c:989)..[38;5|
00000160  3b 33 33 6d 32 30 32 33  31 32 30 34 30 33 30 39  |;33m202312040309|
00000170  30 38 36 32 36 20 1b 5b  31 3b 33 33 6d 44 4c 43  |08626 .[1;33mDLC|
00000180  54 52 4c 1b 5b 30 3b 6d  1b 5b 33 38 3b 35 3b 33  |TRL.[0;m.[38;5;3|
00000190  33 6d 20 1b 5b 31 3b 33  33 6d 4e 4f 54 49 43 45  |3m .[1;33mNOTICE|
000001a0  1b 5b 30 3b 6d 1b 5b 33  38 3b 35 3b 33 33 6d 20  |.[0;m.[38;5;33m |
000001b0  43 54 52 4c 20 61 74 20  31 32 37 2e 30 2e 30 2e  |CTRL at 127.0.0.|
000001c0  31 20 34 32 35 35 20 28  63 6f 6e 74 72 6f 6c 5f  |1 4255 (control_|
000001d0  69 66 2e 63 3a 31 30 31  34 29 1b 5b 30 3b 6d 0a  |if.c:1014).[0;m.|
000001e0 *00*1b 5b 33 38 3b 35 3b  33 39 6d 32 30 32 33 31  |..[38;5;39m20231| <---
000001f0  32 30 34 30 33 30 39 30  38 36 32 36 20 1b 5b 31  |204030908626 .[1|
00000200  3b 33 33 6d 44 4c 47 53  55 50 1b 5b 30 3b 6d 1b  |;33mDLGSUP.[0;m.|
00000210  5b 33 38 3b 35 3b 33 39  6d 20 1b 5b 31 3b 33 33  |[38;5;39m .[1;33|
00000220  6d 4e 4f 54 49 43 45 1b  5b 30 3b 6d 1b 5b 33 38  |mNOTICE.[0;m.[38|
00000230  3b 35 3b 33 39 6d 20 47  53 55 50 20 63 6f 6e 6e  |;5;39m GSUP conn|
00000240  65 63 74 69 6e 67 20 74  6f 20 31 32 37 2e 30 2e  |ecting to 127.0.|
00000250  30 2e 35 3a 34 32 32 32  20 28 67 73 75 70 5f 63  |0.5:4222 (gsup_c|
00000260  6c 69 65 6e 74 2e 63 3a  37 34 29 1b 5b 30 3b 6d  |lient.c:74).[0;m|
00000270  0a 00 32 30 32 33 31 32  30 34 30 33 30 39 30 38  |..20231204030908|
00000280  36 32 36 20 1b 5b 31 3b  33 34 6d 44 4c 47 4c 4f  |626 .[1;34mDLGLO|
00000290  42 41 4c 1b 5b 30 3b 6d  20 1b 5b 31 3b 33 34 6d  |BAL.[0;m .[1;34m|
000002a0  44 45 42 55 47 1b 5b 30  3b 6d 20 76 61 6c 69 64  |DEBUG.[0;m valid|
000002b0  61 74 69 6e 67 20 63 6f  75 6e 74 65 72 20 67 72  |ating counter gr|

The log files were created with .cfg like this:

log file current_log/osmo-msc.log
 logging filter all 1
 logging color 1
 logging print level 1
 logging print category 1
 logging print category-hex 0
 logging print file basename last
 logging print extended-timestamp 1
 logging level set-all debug

 logging level linp notice
 logging level lss7 notice
 logging level lsccp notice
 logging level lsua notice
 logging level lm3ua notice

(from osmo-dev.git/net/)

attached logs and configs in a tar


Files

logtest.tar logtest.tar 290 KB neels, 12/04/2023 02:30 AM

Related issues

Related to libosmocore - Bug #6249: logging: ANSI color sequences should be reset after log messageIn Progressmanawyrm11/07/2023

Actions
Actions #1

Updated by neels 3 months ago

The patch
https://osmocom.org/projects/libosmocore/repository/libosmocore/revisions/11a416827dd9f2da6b7c1db0e1e83adb1e6e5cc8/diff
causes this bug.

I don't understand why yet, but reverting the patch fixes the issue.

Actions #2

Updated by neels 3 months ago

  • Related to Bug #6249: logging: ANSI color sequences should be reset after log message added
Actions #4

Updated by neels 3 months ago

  • Status changed from New to In Progress
  • % Done changed from 0 to 80
Actions #5

Updated by laforge 10 days ago

  • Status changed from In Progress to Resolved
  • Assignee set to neels

Not sure why neels set it only to 80%. I'm not aware of any issue remaining after the patch was merged 2 months ago. Resolving.

Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)