Hi,

I'm trying to parse a logcat file, which is like below:

01-01 00:03:31.788 591 591 W SELinux : Multiple same specifications for qti.ims.ext.
06-16 12:49:15.390 734 1334 I abc : type=1400 audit(0.0:18414): avc: denied { read } for abc
06-16 12:49:15.390 734 734 I e : something here
06-16 12:49:15.403 1502 1668 I Engine: vs_get_temperature: read[0] skin-therm 33922 mC, weight[0] 553


I create one parse rule like below:
%d{MM-dd %H:mm:ss.fff} %t %t %p %c:%m%n

but the output is not correct, as below, output exist 3 problem:
1. line 2,3,4 mixed
2. subpid is missing.
3. the space between pid and subpid is not fixed value. It may be 2 or 3, depends on the length of subpid. I can't find one way to handle such case.


Could you please kindly help me here? 

Thanks!

Hi Alex,

What version of LogViewPlus are you using?  Using v2.4.41, if I parse the file with the pattern you provided, I get a different result.


Which looks like the file was parsed correctly.  Maybe the parser is getting confused before the actual problem is visible?  In which case, I will not be able to reproduce the problem with the lines provided.

There appears to be a little bit of weirdness happening with the colon.  Sometimes it is proceeded with a space, and sometimes it isn't.  It does not appear to mark a place holder for an optional field.  This is a bit strange and might be part of the problem.   

Also, your pattern has "%t" twice.  This is saying you have two sets of data which both belong in the 'Thread' column.  This is not supported and the first set of data would be overwritten by the second.  

Putting this all together, I would recommend parsing the file with:
%d{MM-dd %H:mm:ss.fff} %s{Column1} %t %p %c: %m%n

This is very similar to the pattern you suggested, so I think the problem may be somewhere else.

Hope that helps,

Toby

Hi Toby,

Thanks for your checking and answer, finally I wrote one parser dll and resolved this problem

Have a nice day.

BR
Alex

Thanks for the update Alex.  Glad to hear you got it working.

Were you able to find the underlying issue?  It would be good to know why LogViewPlus was having difficulty with this file.

Toby

im using this
%d %t %s{Column1} %p %m%n
i had to add a global log level in configuration so the "E" gets recongnized as error.
and sometimes i get a bad parsing when there is only one space between the numbers (after the timestamp) as the next two lines show :
01-09 13:24:22.251  4826  4826 I SurfaceFlinger: SFWD update time=19495346470633
01-09 13:24:23.125 26402 26402 I SoundAlivePolicyManager: isGlobalEffectSupportCurrentAudioPath, currentDeviceType : 2

Hi Morty,

It looks like the Thread and String1 columns are left padded to be a minimum length of 5 characters.  I can get a good parse of the sample log entries provided with:

%d %5t %5s{Column1} %p %m%n

It looks like you could even add the logger with:

%d %5t %5s{Column1} %p %c: %m%n

Please see our documentation for more information on fixed length fields.

However, from your screenshot it looks like the log entries above these are also 4 characters long.  If you still have problems, it may help if you could provide some additional log entries.

You needed to add 'E' as a global log level because there is also an 'Emergency' level declared as fatal - so there is a conflict.  I will take a look to see if we can handle 'E' as a special case.

Hope that helps,

Toby

for me is working great with your recommendation, thank you for that,
i dont need more support but in case you want to look further into this im adding a bigger piece of the log,
And for those who wonder how to get the android log live into a file here is the command i use in windows terminal:

adb logcat all > yourfile.txt

my device is connected to my pc with a usb and i had installed android studio (which installs adb),
and using logviewplus i open "yourfile.txt"

Log sample::

01-10 22:27:24.162 363 409 I DBG_FMESEC :[FmmMcfManager   ]: Start offline scanining
01-10 22:27:24.163 363 409 I [MCFSDK_fmm_1.0.2039]_17_McfBleAdapterImpl: getBleScanner - 
01-10 22:27:24.166 363 409 W [MCFSDK_fmm_1.0.2039]_17_McfBleAdapterImpl: stopScan - Ignore - not started
01-10 22:27:24.166 363 409 I [MCFSDK_fmm_1.0.2039]_17_McfBleAdapterImpl: getBleScanner - 
01-10 22:27:24.169 363 409 I [MCFSDK_fmm_1.0.2039]_17_McfBleAdapterImpl: startScan - screenOnFilter - 2
01-10 22:27:24.170 363 409 I [MCFSDK_fmm_1.0.2039]_17_McfBleAdapterImpl: startScan - screenOffFilter - 2
01-10 22:27:24.175  6823  6823 I [MCFServer]_BleAdapterManager: startScan - BAScanCallback{Settings=BleScanSettings{mode=0, rssi=-128, timeout=0, phy =0}, Callback=CB{i=17, h=102983574}}
01-10 22:27:24.277  6823  6823 I [MCFServer]_BleScanner(BA): startScan - BAScanPolicy{, IDs={17}}
01-10 22:27:24.277  6823  6823 I BluetoothAdapter: STATE_BLE_ON
01-10 22:27:24.278  6823  6823 I BluetoothAdapter: appoCount is = 0 G/S = 4/4
01-10 22:27:24.279  6823  6823 I BluetoothAdapter: STATE_BLE_ON
01-10 22:27:24.279  6823  6823 I BluetoothAdapter: appoCount is = 0 G/S = 4/4
01-10 22:27:24.280  6823  6823 I BluetoothAdapter: STATE_BLE_ON
01-10 22:27:24.280  6823  6823 I BluetoothAdapter: appoCount is = 0 G/S = 4/4
01-10 22:27:24.292  6374  7999 D BtGatt.ContextMap: add() - appUid: 1000, appPid: 6823, appName: android.uid.system
01-10 22:27:24.297  6374  6497 I bt_stack: [INFO:gatt_api.cc(950)] GATT_Register 6e9ecb2b-3730-4c17-81cc-7954dc3fbfad
01-10 22:27:24.297  6374  6497 I bt_stack: [INFO:gatt_api.cc(994)] allocated gatt_if=5
01-10 22:27:24.297  6374  6497 I bt_stack: [INFO:gatt_api.cc(1101)] GATT_StartIf gatt_if=5
01-10 22:27:24.300  6374  6436 D BtGatt.GattService: onScannerRegistered() - UUID=6e9ecb2b-3730-4c17-81cc-7954dc3fbfad, scannerId=5, status=0
01-10 22:27:24.308  6374  7999 I BluetoothAdapter: STATE_BLE_ON
01-10 22:27:24.309  6374  7999 I BluetoothAdapter: bleAppCnt is = 4
01-10 22:27:24.335  6374  6471 I BluetoothAdapter: STATE_BLE_ON
01-10 22:27:24.335  6374  6471 I BluetoothAdapter: appoCount is = 0 G/S = 4/4
01-10 22:27:24.341  6374  6475 W BtGatt.GattService: checkToReportData before boot completed
01-10 22:27:24.341  6374  6471 I BluetoothAdapter: STATE_BLE_ON
01-10 22:27:24.341  6374  6475 E BtGatt.GattService: [GSIM LOG]: gsimLogHandler, msg: MESSAGE_SCAN_START, appName: android.uid.system, scannerId: 5, reportDelayMillis=0
01-10 22:27:24.342  6374  6471 I BluetoothAdapter: appoCount is = 0 G/S = 4/4
01-10 22:27:24.342  6374  6471 I BluetoothAdapter: STATE_BLE_ON
01-10 22:27:24.343  6374  6471 I BluetoothAdapter: appoCount is = 0 G/S = 4/4
01-10 22:27:24.360  6374  6471 D BtGatt.ScanManager: configureFilterParamter() : onFoundTimeout | onLostTimeout | onFoundCount | numOfTrackingEntries | scanFilterRssiThreshold | trackableScanFilterRssiThreshold | matchMode
01-10 22:27:24.360  6374  6471 D BtGatt.ScanManager: configureFilterParamter() : __________500__|________10000__|___________1__|___________________0__|___________________-128__|____________________________-128__|________1_
01-10 22:27:24.371  6374  6471 D BtGatt.ScanManager: configureFilterParamter() : onFoundTimeout | onLostTimeout | onFoundCount | numOfTrackingEntries | scanFilterRssiThreshold | trackableScanFilterRssiThreshold | matchMode
01-10 22:27:24.371  6374  6471 D BtGatt.ScanManager: configureFilterParamter() : __________500__|________10000__|___________1__|___________________0__|___________________-128__|____________________________-128__|________1_
01-10 22:27:24.381  6374  6497 W bt_btm  : btm_ble_disable_resolving_list() rl_state = 0xb, rl_mask = 0x2, to_resume = 1
01-10 22:27:24.381  6374  6497 W bt_btm  : btm_ble_enable_resolving_list() rl_state = 0x9, rl_mask = 0x2
01-10 22:27:24.655  6571  6571 D BoundBrokerSvc: onUnbind: Intent { act=com.google.android.gms.measurement.START pkg=com.google.android.gms }
01-10 22:27:24.712  4849  4849 I SurfaceFlinger: SFWD update time=9972350433983
01-10 22:27:24.928  5878  5878 I IpcDispatcher<0>: handleMessage: EVENT_SEC_CHANNEL_PROXY_DEAD cookie = 4955 mSecChannelProxyCookie = 4955
01-10 22:27:24.930  4257  4257 I hwservicemanager: getTransport: Cannot find entry vendor.samsung.hardware.radio.channel@2.0::ISehChannel/imsd in either framework or device manifest.
01-10 22:27:24.931  5878  5878 E IpcDispatcher<0>: SecChannelProxy getService/setCallback: java.util.NoSuchElementException
01-10 22:27:25.044  4783 32603 E HYPER-HAL: [HandlerSysfs.cpp]doResourceHandling(): Couldn't Open Sysfs - /sys/kernel/mm/vmscan/am_app_launch
01-10 22:27:25.046  4783 32603 I HYPER-HAL: [ResourceManager.cpp]removeResource(): [CPUMaxFreq] RemoveResource Request ID : 28143766
01-10 22:27:25.047  4783 32603 I HYPER-HAL: [RequestManager.cpp]releaseLocked(): Released ID : 28143766
01-10 22:27:25.331  5133  7424 I EDMNativeHelperService: isCameraEnabled
01-10 22:27:25.331  5133  7424 D EDMNativeHelper: isCameraEnabled
01-10 22:27:25.337  5133  7424 D EDMNativeHelper: checking for camera in EnterpriseDeviceManagerService
01-10 22:27:25.337  5133  7424 D EnterpriseDeviceManagerService: isCameraEnabledNative
01-10 22:27:25.337  5133  7424 D EnterpriseDeviceManagerService: checking for camera in restriction policy
01-10 22:27:25.338  5133  7424 D RestrictionPolicy: isCameraEnabled ret(true) userId(0) cxtInfo.mCallerUid(10364) cxtInfo.mContainerId(0)
01-10 22:27:25.967  5133  5460 I Pageboost: Launcher App Execution
01-10 22:27:26.084  5133  5460 I Pageboost: IoRecord pid : 23885
01-10 22:27:26.098  5133  5460 I Pageboost: IoRecord pid : 23885, result_size : 14098
01-10 22:27:26.115  4416  4416 D io_stats: !@ 8,0 r 559628 14758484 w 84810 2568420 d 53963 15318856 f 47573 57186 iot 177836 149357 th 102400 0 0 pt 0 inp 0 0 9973.749
01-10 22:27:26.139  5133  5460 I Pageboost: db create : CREATE TABLE IF NOT EXISTS mxmotionarfacemocap (FILENAME TEXT, OFFSET INTEGER, SIZE INTEGER, FORVRAMDISK INTEGER, BITMAP BLOB, unique (FILENAME, OFFSET) );
01-10 22:27:26.142  5133  5460 I Pageboost: db insert start
01-10 22:27:26.147  5133  5460 I Pageboost: db insert done, overLimit false
01-10 22:27:26.148  5133  5460 I Pageboost: captureFinished success : 38395904
01-10 22:27:26.149  5133  5460 I Pageboost: db create : CREATE TABLE IF NOT EXISTS mxmotionarfacemocap (FILENAME TEXT, OFFSET INTEGER, SIZE INTEGER, FORVRAMDISK INTEGER, BITMAP BLOB, unique (FILENAME, OFFSET) );
01-10 22:27:26.160  5133  5460 I Pageboost: db update :mx.motion.ar.facemocap ret 1
01-10 22:27:26.167 23885 342 V third_party/redwood/infrastructure/jni_common/jni_helper.cc: JniHelper: attached thread (Called from line 93).
01-10 22:27:26.167 23885 342 V third_party/redwood/infrastructure/jni_common/jni_helper.cc: ~JniHelper: about to detach thread (Called from line 93).
01-10 22:27:26.168 23885 342 V third_party/redwood/infrastructure/jni_common/jni_helper.cc: ~JniHelper: detached thread (Called from line 93).
01-10 22:27:26.168 23885 342 I native  : I0110 22:27:26.168282   342 model_selector.cc:82] Switching to the ultra lite model.
01-10 22:27:26.221 23885 338 I tflite  : Replacing 176 node(s) with delegate (TfLiteXNNPackDelegate) node, yielding 2 partitions.
01-10 22:27:26.391  5133  5460 I Pageboost: memUsage collected : 197622 27126 103920 for mx.motion.ar.facemocap 23885
01-10 22:27:26.398  5397  5397 I wpa_supplicant: Heartbeat 997
01-10 22:27:27.140  6170  6170 D BoundBrokerSvc: onUnbind: Intent { act=com.google.android.gms.udc.service.START pkg=com.google.android.gms }
01-10 22:27:27.160  4903 32728 I Camera3-Device: Watchdog...
01-10 22:27:27.181  5133  9591 D SemGameManager: getGMSBinder(), begin
01-10 22:27:27.183  5133  9591 D SemGameManager: getGMSBinder(), successful: true
01-10 22:27:27.183  5133  9591 D GameManagerService: identifyGamePackage. mx.motion.ar.facemocap, mCurrentUserId: 0, callerUserId: 0
01-10 22:27:27.183  5133  9591 D PkgDataHelper: getGamePkgData(). mx.motion.ar.facemocap
01-10 22:27:27.194  4786 32731 I ExynosCameraFrameManager: [CAM(1)][RUNNING FRAME WORKER]-(workerMain[952]): wait and pop fail, ret(-110)
01-10 22:27:27.906  5133 32640 I SystemUiVisibilityPolicyController: handleMessage: entry what = 101
01-10 22:27:28.122  4416  4416 D io_stats: !@ 8,0 r 559696 14759272 w 84821 2568832 d 54025 15319588 f 47620 57237 iot 177864 149385 th 102400 0 0 pt 0 inp 0 0 9975.755
01-10 22:27:28.344  5133  5565 I EDMNativeHelperService: isCameraEnabled
01-10 22:27:28.344  5133  5565 D EDMNativeHelper: isCameraEnabled
01-10 22:27:28.349  5133  5565 D EDMNativeHelper: checking for camera in EnterpriseDeviceManagerService
01-10 22:27:28.350  5133  5565 D EnterpriseDeviceManagerService: isCameraEnabledNative
01-10 22:27:28.350  5133  5565 D EnterpriseDeviceManagerService: checking for camera in restriction policy
01-10 22:27:28.350  5133  5565 D RestrictionPolicy: isCameraEnabled ret(true) userId(0) cxtInfo.mCallerUid(10364) cxtInfo.mContainerId(0)
01-10 22:27:28.451 23885 32646 I native  : I0110 22:27:28.451508 32646 session.cc:3330] Update Frame Delay to 4 frames.
01-10 22:27:28.931  5878  5878 I IpcDispatcher<0>: handleMessage: EVENT_SEC_CHANNEL_PROXY_DEAD cookie = 4957 mSecChannelProxyCookie = 4957
01-10 22:27:28.932  4257  4257 I hwservicemanager: getTransport: Cannot find entry vendor.samsung.hardware.radio.channel@2.0::ISehChannel/imsd in either framework or device manifest.
01-10 22:27:28.934  5878  5878 E IpcDispatcher<0>: SecChannelProxy getService/setCallback: java.util.NoSuchElementException
01-10 22:27:29.212  7489  8847 I SDHMS:G : -99 > surface_temperature_0
01-10 22:27:29.215  7489  8847 I SDHMS:G : writeSysfs:: path() : /sys/class/audio/amp/surface_temperature_0 exist() : false canWrite() : false
01-10 22:27:29.215  7489  8847 I SDHMS:G : -99 > surface_temperature_1
01-10 22:27:29.216  7489  8847 I SDHMS:G : writeSysfs:: path() : /sys/class/audio/amp/surface_temperature_1 exist() : false canWrite() : false
01-10 22:27:29.216  7489  8847 I SDHMS:G : SIOP:: AP:190(303,60) BAT:237(237,0) USB:0(0,0) CHG:273(273,0) WIFI:256(256,0) BLK:252(252,0) 
01-10 22:27:29.708  5133  6661 D BatteryService: Sending ACTION_BATTERY_CHANGED. scale:100, info:{.chargerAcOnline = false, .chargerUsbOnline = true, .chargerWirelessOnline = false, .maxChargingCurrent = 0, .maxChargingVoltage = 0, .batteryStatus = CHARGING, .batteryHealth = GOOD, .batteryPresent = true, .batteryLevel = 74, .batteryVoltage = 3945, .batteryTemperature = 237, .batteryCurrent = -509, .batteryCycleCount = 0, .batteryFullCharge = 7040000, .batteryChargeCounter = 4878080, .batteryTechnology = Li-ion}
01-10 22:27:29.708  5133  6661 D BatteryService: online:5, current avg:-515, charge type:2, POGO powered:false, power sharing:false, high voltage charger:false, charger_type:0, capacity:280000, misc_event:0x10000, current_event:0x8000, current_now:-509
01-10 22:27:29.712  4849  4849 I SurfaceFlinger: SFWD update time=9977350629402
01-10 22:27:29.713  5133  5133 D PhoneWindowManagerExt: ACTION_BATTERY_CHANGED - Level=74, status=2
01-10 22:27:29.716  5133  5133 D SemWifiApBroadcastReceiver: Received : android.intent.action.BATTERY_CHANGED
01-10 22:27:29.722  5133  5256 D MotionRecognitionService: onReceive : ACTION_BATTERY_CHANGED, Plugged: 2
01-10 22:27:29.723  5133  5256 I MotionRecognitionService: [TA] In/out: true, curr state: 1
01-10 22:27:29.726  5474  5474 I PowerUI : BATTERY_HEALTH_CHECK extraHealth=2 mBatteryMiscEvent=65536
01-10 22:27:29.727  5474  5474 D PowerUI : priorPlugType = 2 mPlugType = 2 priorBatteryStatus = 2 mBatteryStatus = 2
01-10 22:27:29.736  5454  5454 D SemBigDataInfoController: Intent : android.intent.action.BATTERY_CHANGED
01-10 22:27:29.740 23190 23190 D TransportListener: Updating
01-10 22:27:29.753  5474  5474 D PowerUI.Notification: showChargingNotice oldChargingType : 7 currentChargingType : 7 oldChargingTime : 56126000 mChargingTime : 56126000
01-10 22:27:29.753  5474  5474 D PowerUI.Notification: There is no change about charging status, so return!
01-10 22:27:29.753  5474  5474 I PowerUI : mBatteryMiscEvent = 65536
01-10 22:27:29.753  5474  5474 D PowerUI : showing power sharing dialogfalse
01-10 22:27:29.756  5474  5474 D KeyguardUpdateMonitor: received broadcast android.intent.action.BATTERY_CHANGED
01-10 22:27:29.757  5474  5474 I AODBatteryManager: updateBatteryData: ACTION_BATTERY_CHANGED
01-10 22:27:29.774  5474  5474 I AODBatteryManager: saveBatteryData : AOD BatteryData [mBatteryLevel=74, mBatteryStatus=CHARGING, mBatteryPlugType=USB, mBatteryPlugged=true, mRemainingChargeTime=56126000, mBatteryChargingType=1, mBatteryChargerType=NORMAL, mBatteryOnline=NOT_DEFINED, mBatterySwellingMode=NONE, mBatteryProtectMode=false]
01-10 22:27:29.783  5474  5474 D KeyguardUpdateMonitor: handleBatteryUpdate
01-10 22:27:29.799  6170  6170 D BoundBrokerSvc: onUnbind: Intent { act=com.google.android.gms.scheduler.ACTION_PROXY_SCHEDULE cmp=com.google.android.gms/.chimera.PersistentInternalBoundBrokerService }
01-10 22:27:30.129  4416  4416 D io_stats: !@ 8,0 r 559707 14759420 w 84821 2568832 d 54025 15319588 f 47621 57238 iot 177876 149387 th 102400 0 0 pt 0 inp 0 0 9977.762
01-10 22:27:30.878  5133  5223 D SensorService: [SO] 9.752 0.237 0.757
01-10 22:27:31.354  5133  7355 I EDMNativeHelperService: isCameraEnabled
01-10 22:27:31.355  5133  7355 D EDMNativeHelper: isCameraEnabled
01-10 22:27:31.356  5133  7355 D EDMNativeHelper: checking for camera in EnterpriseDeviceManagerService
01-10 22:27:31.356  5133  7355 D EnterpriseDeviceManagerService: isCameraEnabledNative
01-10 22:27:31.356  5133  7355 D EnterpriseDeviceManagerService: checking for camera in restriction policy
01-10 22:27:31.356  5133  7355 D RestrictionPolicy: isCameraEnabled ret(true) userId(0) cxtInfo.mCallerUid(10364) cxtInfo.mContainerId(0)

Thanks for the update Morty. 

I appreciate the help you left for others - nice one!  I have applied some additional formatting to make that more clear.

The sample log entries are also really helpful.  Unfortunately, I am still not happy with how this file is being parsed as some log entries are not being parsed correctly with the pattern I provided above.  I can see that the logger column is sometimes missing and log entries are being joined together:

  

These files have a very strange format.  Sometimes a minimum length is used and sometimes it is not.  Format modifiers should probably not be used here because the format does not actually follow any minimum / maximum character rules.

LogViewPlus does not have a good solution for this at the moment.  I think what is needed is the ability to say that this field is required.  The problem with the empty spaces is that LogViewPlus thinks the field is missing.  If I have " %s " and the log entry contains just two spaces at this position, then the field I am looking for is missing.  In these logcat files, the field is not missing and we need to keep reading.

So I think we need the ability to tell the parser that this field will never be missing.  Just keep reading until you find it.  Maybe * would be a good way to indicate this?  Something like:

%d %*t %*s{Column1} %p %c: %m%n

It is not very pretty, but this is a real edge case.  I have never seen it before.  I will need to have a think about it and get back to you. 

Thanks,

Toby

Hi Morty,

Apologies for the delay in getting back to you.

I investigated the solution a bit further.  LogViewPlus can parse this file with:

%d{MM-dd %H:mm:ss.fff} %3s{PID} %3s{TID} %p %c: %m%n

In this scenario, we are using format modifiers in an unusual way.  We are using them to skip forward and ignore the variable spacing.  This is a much cleaner solution than the development work proposed above.  It is also backwards compatible with earlier versions of LogViewPlus. 

We have also released LogViewPlus v2.5.53 as a BETA release.  The new release will treat the 'E' priority level as an error.  

Hope that helps,

Toby